The logs in activation is not complete #2548

andrewnet · 2017-07-31T18:33:54Z

Environment details:

Bluemix

Steps to reproduce the issue:

This happens randomly. Most activation contain complete logs however some activation do not have complete logs. The entry point of our OpenWhisk java action looks like below. So if the logs in activation contains the complete log, you should see Exit WhiskMain, resp=... in the logs; this is not the case for all the activation.

We checked the response object in the activation, it contains the right object that prove the activation finished properly.

	public static JsonObject main(JsonObject args) {
    	JsonObject resp = null;
    	try {
    		logger.info("Enter WhiskMain");
    		//calling our business logic
    		resp = executeImpl(args);
    		return resp;
    	} catch (RuntimeException | Error e) {
    		logger.error("WhiskMain caught unchecked throwable", e);
    		throw e;
	} finally {
    		logger.info("Exit WhiskMain, resp=" + resp);
	}
    }

Provide the expected results and outputs:

We should always see Exit WhiskMain, resp=... in the logs of activation.

Provide the actual results and outputs:

The logs in activation only contains some of the logs and the line Exit WhiskMain, resp=... doesn't show up in some of the activation (while others do)

Additional information you deem important:

This problem is blocking us to release our product, as we need the complete log to troubleshooting why activation didn't go as we expected.

The text was updated successfully, but these errors were encountered:

andrewnet · 2017-08-01T14:16:39Z

Just to avoid any doubt, we tried below too. We see the lines printed directly to System.out and System.err were missing too.

	public static JsonObject main(JsonObject args) {
    	JsonObject resp = null;
    	try {
    		logger.info("Enter WhiskMain");
    		logger.info(getCallInfo());
    		
    		//temporary workaround to prevent JVM heap size is go beyond 
    		//the container limit of openwhisk. the issue can be tracked at
    		//https://github.com/apache/incubator-openwhisk/issues/2389
    		System.gc();
    		
    		resp = executeImpl(args);
    		return resp;
    	} catch (RuntimeException | Error e) {
    		logger.error("WhiskMain caught unchecked throwable", e);
    		throw e;
	} finally {
		System.out.println("Printed by System.out - before last log item");
		System.err.println("Printed by System.err - before last log item");
    		logger.info("Exit WhiskMain, resp=" + resp);
		System.out.println("Printed by System.out - after last log item");
		System.err.println("Printed by System.err - after last log item");
		System.out.flush();
		System.err.flush();
	}
    }

rabbah · 2017-08-01T17:00:10Z

Thanks for the additional details. I'll try to reproduce and address. Can you confirm that you observe the activation results are all successful (no killed actions)? We have a theory which I'll try to test.

andrewnet · 2017-08-01T22:52:57Z

Yes, I confirm that the activation results are successful for those I inspected. I didn't inspect all since there were thousands activation.

andrewnet · 2017-08-02T01:45:12Z

This is what it looks like for one of those activation (I truncated some of the log lines as they were very long):

C:\Software\apache-jmeter-3.2\bin>wsk activation get b6a8c90e52644dfba962b576f83182da
ok: got activation b6a8c90e52644dfba962b576f83182da
{
    "namespace": "Entity_discovery_qa",
    "name": "action_create_asset_yp-qa",
    "version": "0.0.10",
    "subject": "discopro@us.ibm.com",
    "activationId": "b6a8c90e52644dfba962b576f83182da",
    "start": 1501571113739,
    "end": 1501571214226,
    "duration": 100487,
    "response": {
        "status": "success",
        "statusCode": 0,
        "success": true,
        "result": {
            "resources": [
                "9d458938-9fe7-479e-87a4-d04fc04958b2",
                "433ce362-36ee-4c21-bdb3-d1958f82f4cf",
                "b3e7b059-67b1-40fc-9743-99f83c8bbbde",
                "b235cc6b-7542-4c2b-856b-89ce9ba1bfc3",
                "1b1ba1d2-402c-4dcd-bc76-b401bdca460f",
                "299e0b1a-745b-48cc-be2a-be0788feb1b4",
                "6bebaf3a-3d5e-4783-9588-6bdb76387671",
                "fc777d4a-1565-455a-ac23-d4385e7c8c44",
                "1a68b82f-0595-4ae0-963e-887e7e4435de",
                "156aa79f-c09f-49ed-ac94-e3572de47fee",
                "14de3f44-900a-4c28-bf28-e493103c94c7",
                "08e4fb74-d7d7-4227-9efa-3cf919496c20"
            ]
        }
    },
    "logs": [
        "2017-08-01T07:05:13.74619846Z  stderr: Aug 01, 2017 7:05:13 AM com.ibm.wdp.discovery.openwhisk.WhiskMain main",
        "2017-08-01T07:05:13.746241872Z stderr: INFO: Enter WhiskMain",
        "2017-08-01T07:05:13.752853974Z stderr: Aug 01, 2017 7:05:13 AM com.ibm.wdp.discovery.openwhisk.WhiskMain main",
        "2017-08-01T07:05:13.752873261Z stderr: INFO: System runtime: jvm_used_count=3, free_memory=132465168, total_memory=160432128, max_memory=1860698112, available_processors=4",
        "2017-08-01T07:05:14.732612726Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel execute",
        "2017-08-01T07:05:14.73265893Z  stderr: INFO: Enter CreateAssetsActionParallel",
        "2017-08-01T07:05:14.744277515Z stderr: Aug 01, 2017 7:05:14 AM com.rabbitmq.client.TrustEverythingTrustManager <init>",
        "2017-08-01T07:05:14.744297374Z stderr: WARNING: This trust manager trusts every certificate, effectively disabling peer verification. This is convenient for local development but pro
        "2017-08-01T07:05:14.842782234Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.842822185Z stderr: INFO: Input has 12 messages",
        "2017-08-01T07:05:14.843874184Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.84391005Z  stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.858818008Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.858841756Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.867421954Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.86744135Z  stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.888620188Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.888641042Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.900290098Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.900319978Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.919856859Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.919885163Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.931323195Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.931341002Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.946509952Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.946535797Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:14.97495227Z  stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:14.974967321Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:15.056608765Z stderr: Aug 01, 2017 7:05:14 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:15.056632376Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:15.073073333Z stderr: Aug 01, 2017 7:05:15 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:15.073092816Z stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:15.104481487Z stderr: Aug 01, 2017 7:05:15 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:15.10451676Z  stderr: INFO: {\"param_reposted_times\":null,\"discovery\":{\"metadata\":{\"id\":\"e53f341bc2904c69ad7051ecc0f53238\",\"invoked_by\":\"discoveryuser01@ .... ",
        "2017-08-01T07:05:15.11423698Z  stderr: Aug 01, 2017 7:05:15 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallel getTasks",
        "2017-08-01T07:05:15.114257583Z stderr: INFO: Created 12 tasks",
        "2017-08-01T07:05:15.114485171Z stderr: Aug 01, 2017 7:05:15 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallelHelper executeParallel",
        "2017-08-01T07:05:15.114497916Z stderr: INFO: Start creating all assets in parallel...",
        "2017-08-01T07:06:54.205742804Z stderr: Aug 01, 2017 7:06:54 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallelHelper executeParallel",
        "2017-08-01T07:06:54.205797949Z stderr: INFO: Finished creating all assets",
        "2017-08-01T07:06:54.206156106Z stderr: Aug 01, 2017 7:06:54 AM com.ibm.wdp.discovery.core.process.openwhisk.action.parallel.CreateAssetsActionParallelHelper createAssets",
        "2017-08-01T07:06:54.206167233Z stderr: INFO: exec result: discovery_id=e53f341bc2904c69ad7051ecc0f53238, create_succ=12, create_fail=0, create_retry=0, created_asset_ids=[9d458938-9f .... ",
        "2017-08-01T07:06:54.224796361Z stdout: Printed by System.out - before last log item",
        "2017-08-01T07:06:54.225294612Z stdout: Printed by System.out - after last log item"
    ],
    "annotations": [
        {
            "key": "limits",
            "value": {
                "logs": 10,
                "memory": 256,
                "timeout": 300000
            }
        },
        {
            "key": "path",
            "value": "Entity_discovery_qa/action_create_asset_yp-qa"
        }
    ],
    "publish": false
}

andrewnet · 2017-08-08T13:21:32Z

Hi, just want to follow up on the progress of this defect and see if there is any update? Thanks.

andrewnet · 2017-09-05T15:43:44Z

Hi, is there any progress on the issue? Thanks.

rabbah · 2017-11-18T01:53:23Z

@andrewnet I did not manage to reproduce this - are you still encountering truncated log issues?

andrewnet · 2017-11-18T04:42:12Z

Hi @rabbah , yes, we still see the problem. In the last run we did yesterday, 293 out of 28794 activation do not have full log.

rabbah · 2018-07-08T03:26:21Z

I have added log frame markers to the Java runtime apache/openwhisk-runtime-java#63; their absence doesn't necessarily cause log truncation, but the markers do explicitly flush the streams.

rabbah added java logging labels Jul 31, 2017

andrewnet mentioned this issue Jul 31, 2017

Make action container log reading more robust #2137

Closed

rabbah mentioned this issue Nov 25, 2017

activation logs squashed well before 10MB, and with no truncation warning #1920

Closed

rabbah mentioned this issue Jul 8, 2018

Logs and tests apache/openwhisk-runtime-java#63

Merged

dgrove-oss closed this as completed in apache/openwhisk-runtime-java#63 Jul 9, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

The logs in activation is not complete #2548

The logs in activation is not complete #2548

andrewnet commented Jul 31, 2017

andrewnet commented Aug 1, 2017

rabbah commented Aug 1, 2017

andrewnet commented Aug 1, 2017

andrewnet commented Aug 2, 2017

andrewnet commented Aug 8, 2017

andrewnet commented Sep 5, 2017

rabbah commented Nov 18, 2017 •

edited

andrewnet commented Nov 18, 2017

rabbah commented Jul 8, 2018

The logs in activation is not complete #2548

The logs in activation is not complete #2548

Comments

andrewnet commented Jul 31, 2017

Environment details:

Steps to reproduce the issue:

Provide the expected results and outputs:

Provide the actual results and outputs:

Additional information you deem important:

andrewnet commented Aug 1, 2017

rabbah commented Aug 1, 2017

andrewnet commented Aug 1, 2017

andrewnet commented Aug 2, 2017

andrewnet commented Aug 8, 2017

andrewnet commented Sep 5, 2017

rabbah commented Nov 18, 2017 • edited

andrewnet commented Nov 18, 2017

rabbah commented Jul 8, 2018

rabbah commented Nov 18, 2017 •

edited