2022-12-16T15:05:05+08:00 {"instant":{"epochSecond":1671174305,"nanoOfSecond":669210223},"thread":"model-load-de-id-55__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Starting load for model de-id-55__isvc-60ac5fc3c4 type=rt:dep-host-11","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:05:05+08:00 {"instant":{"epochSecond":1671174305,"nanoOfSecond":674346508},"thread":"mm-task-thread-9","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Published new instance record: InstanceRecord [lruTime=1671169768301 (76 minutes ago), count=3, capacity=575816, used=273087 (47%), loc=10.250.94.161, zone=<none>, labels=[mt:custom, mt:custom:1, rt:dep-host-11], startTime=1671173325261 (16 minutes ago), vers=0, loadThreads=1, loadInProg=1, reqsPerMin=0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":48,"threadPriority":5}
2022-12-16T15:05:38+08:00 {"instant":{"epochSecond":1671174338,"nanoOfSecond":770227346},"thread":"model-load-de-id-55__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Load of model de-id-55__isvc-60ac5fc3c4 type=rt:dep-host-11 completed in 33100ms","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:05:38+08:00 {"instant":{"epochSecond":1671174338,"nanoOfSecond":770733818},"thread":"model-load-de-id-55__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Model de-id-55__isvc-60ac5fc3c4 loading completed successfully","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:05:38+08:00 {"instant":{"epochSecond":1671174338,"nanoOfSecond":771008980},"thread":"model-load-de-id-55__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Model de-id-55__isvc-60ac5fc3c4 size = 136482 units, ~1066MiB","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:05:38+08:00 {"instant":{"epochSecond":1671174338,"nanoOfSecond":778074687},"thread":"mm-task-thread-9","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Published new instance record: InstanceRecord [lruTime=1671169768301 (76 minutes ago), count=3, capacity=575816, used=409446 (71%), loc=10.250.94.161, zone=<none>, labels=[mt:custom, mt:custom:1, rt:dep-host-11], startTime=1671173325261 (17 minutes ago), vers=0, loadThreads=1, loadInProg=0, reqsPerMin=0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":48,"threadPriority":5}
2022-12-16T15:06:15+08:00 {"instant":{"epochSecond":1671174375,"nanoOfSecond":3748926},"thread":"invoke-ex-de-id-55__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Attempting to add second copy of model de-id-55__isvc-60ac5fc3c4 in another instance since it is in use","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":57,"threadPriority":5}
2022-12-16T15:06:51+08:00 {"instant":{"epochSecond":1671174411,"nanoOfSecond":773707170},"thread":"janitor-task","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Janitor cache pruning task took 0ms for 3 entries","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":47,"threadPriority":5}
2022-12-16T15:06:51+08:00 {"instant":{"epochSecond":1671174411,"nanoOfSecond":774445128},"thread":"janitor-task","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Janitor registry pruning task took 0ms for 3/8 entries","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":47,"threadPriority":5}
2022-12-16T15:08:00+08:00 {"instant":{"epochSecond":1671174480,"nanoOfSecond":899406533},"thread":"mmesh-req-thread-3","level":"INFO","loggerName":"com.ibm.watson.modelmesh.VModelManager","message":"Added new VModel de-id-66 pointing to model de-id-66__isvc-60ac5fc3c4","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","contextMap":{},"threadId":56,"threadPriority":5}
2022-12-16T15:08:00+08:00 {"instant":{"epochSecond":1671174480,"nanoOfSecond":905774032},"thread":"invoke-ex-de-id-66__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"About to enqueue load for model de-id-66__isvc-60ac5fc3c4 with initial weight 123 units (~1MiB), with priority 1671170880884","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":56,"threadPriority":5}
2022-12-16T15:08:00+08:00 {"instant":{"epochSecond":1671174480,"nanoOfSecond":906271861},"thread":"model-load-de-id-66__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Starting load for model de-id-66__isvc-60ac5fc3c4 type=rt:dep-host-11","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:08:00+08:00 {"instant":{"epochSecond":1671174480,"nanoOfSecond":911276807},"thread":"mm-task-thread-7","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Published new instance record: InstanceRecord [lruTime=1671169768301 (79 minutes ago), count=4, capacity=575816, used=409569 (71%), loc=10.250.94.161, zone=<none>, labels=[mt:custom, mt:custom:1, rt:dep-host-11], startTime=1671173325261 (19 minutes ago), vers=0, loadThreads=1, loadInProg=1, reqsPerMin=0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":46,"threadPriority":5}
2022-12-16T15:08:36+08:00 {"instant":{"epochSecond":1671174516,"nanoOfSecond":985824480},"thread":"model-load-de-id-66__isvc-60ac5fc3c4","level":"ERROR","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Load failed for model de-id-66__isvc-60ac5fc3c4 type=rt:dep-host-11 after 36078ms","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:08:37+08:00 {"instant":{"epochSecond":1671174516,"nanoOfSecond":986546840},"thread":"model-load-de-id-66__isvc-60ac5fc3c4","level":"ERROR","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Model load failed for de-id-66__isvc-60ac5fc3c4 type=rt:dep-host-11","thrown":{"commonElementCount":0,"localizedMessage":"UNAVAILABLE: Failed to load Model due to MLServer runtime error: rpc error: code = Unavailable desc = error reading from server: EOF","message":"UNAVAILABLE: Failed to load Model due to MLServer runtime error: rpc error: code = Unavailable desc = error reading from server: EOF","name":"io.grpc.StatusRuntimeException","extendedStackTrace":[{"class":"io.grpc.Status","method":"asRuntimeException","file":"Status.java","line":535,"exact":false,"location":"grpc-api-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.stub.ClientCalls$UnaryStreamToFuture","method":"onClose","file":"ClientCalls.java","line":542,"exact":false,"location":"grpc-stub-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.internal.ClientCallImpl","method":"closeObserver","file":"ClientCallImpl.java","line":562,"exact":false,"location":"grpc-core-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.internal.ClientCallImpl","method":"access$300","file":"ClientCallImpl.java","line":70,"exact":false,"location":"grpc-core-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed","method":"runInternal","file":"ClientCallImpl.java","line":743,"exact":false,"location":"grpc-core-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed","method":"runInContext","file":"ClientCallImpl.java","line":722,"exact":false,"location":"grpc-core-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.internal.ContextRunnable","method":"run","file":"ContextRunnable.java","line":37,"exact":false,"location":"grpc-core-1.46.0.jar","version":"1.46.0"},{"class":"io.grpc.internal.SerializingExecutor","method":"run","file":"SerializingExecutor.java","line":133,"exact":false,"location":"grpc-core-1.46.0.jar","version":"1.46.0"},{"class":"java.util.concurrent.ThreadPoolExecutor","method":"runWorker","file":"ThreadPoolExecutor.java","line":1136,"exact":false,"location":"?","version":"?"},{"class":"java.util.concurrent.ThreadPoolExecutor$Worker","method":"run","file":"ThreadPoolExecutor.java","line":635,"exact":false,"location":"?","version":"?"},{"class":"java.lang.Thread","method":"run","file":"Thread.java","line":833,"exact":false,"location":"?","version":"?"}]},"endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:08:37+08:00 {"instant":{"epochSecond":1671174517,"nanoOfSecond":2424372},"thread":"model-load-de-id-66__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Delaying unload of model de-id-66__isvc-60ac5fc3c4 for at least 1000ms","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:08:37+08:00 {"instant":{"epochSecond":1671174517,"nanoOfSecond":11694103},"thread":"model-load-de-id-66__isvc-60ac5fc3c4","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"ModelRecord updated for de-id-66__isvc-60ac5fc3c4: locations={}, failures={458b8f-m2cgf=1671174516986}","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":51,"threadPriority":5}
2022-12-16T15:08:38+08:00 {"instant":{"epochSecond":1671174518,"nanoOfSecond":3067017},"thread":"mm-task-thread-3","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Initiating unload of model de-id-66__isvc-60ac5fc3c4","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":36,"threadPriority":5}
2022-12-16T15:08:38+08:00 {"instant":{"epochSecond":1671174518,"nanoOfSecond":6060163},"thread":"grpc-default-executor-7","level":"WARN","loggerName":"com.ibm.watson.modelmesh.SidecarModelMesh","message":"Unload of model de-id-66__isvc-60ac5fc3c4 failed, queueing 90 more time(s) for retry: UNAVAILABLE: Failed to unload model from MLServer","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":81,"threadPriority":5}
2022-12-16T15:08:49+08:00 {"instant":{"epochSecond":1671174529,"nanoOfSecond":370139037},"thread":"grpc-default-executor-7","level":"INFO","loggerName":"com.ibm.watson.modelmesh.SidecarModelMesh","message":"Model de-id-66__isvc-60ac5fc3c4 unloaded successfully following retry","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":81,"threadPriority":5}
2022-12-16T15:08:49+08:00 {"instant":{"epochSecond":1671174529,"nanoOfSecond":370627156},"thread":"grpc-default-executor-7","level":"INFO","loggerName":"com.ibm.watson.modelmesh.SidecarModelMesh","message":"Model de-id-66__isvc-60ac5fc3c4 unloaded successfully following retry","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":81,"threadPriority":5}
2022-12-16T15:08:49+08:00 {"instant":{"epochSecond":1671174529,"nanoOfSecond":370910525},"thread":"grpc-default-executor-7","level":"INFO","loggerName":"com.ibm.watson.modelmesh.ModelMesh","message":"Unload of de-id-66__isvc-60ac5fc3c4 completed in 11367ms","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","contextMap":{},"threadId":81,"threadPriority":5}